<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">
<head>
	<meta http-equiv="Content-Type" content="text/html; charset=UTF-8" />
	<title>query_profiling: common_schema documentation</title>
	<meta name="description" content="query_profiling: common_schema" />
	<meta name="keywords" content="query_profiling: common_schema" />
	<link rel="stylesheet" type="text/css" href="css/style.css" />
</head>

<body>
	<div id="main">
		<div id="header">
			<h1>common_schema</h1> <strong>2.2</strong> documentation
			<div class="subtitle">DBA's framework for MySQL</div>
		</div>
		<div id="contentwrapper">
			<div id="content">
				<h2><a href="query_profiling.html">query_profiling</a></h2>	
<h3>NAME</h3>
query_profiling: Per query profiling info, aggregated by query states
<h3>TYPE</h3>
View

<h3>DESCRIPTION</h3>

<p><i>query_profiling</i> presents with pretty profiling info for queries executed within the session. 
</p>


<p>
	Based on the INFORMATION_SCHEMA.PROFILING table, this view aggregates data by query state, and 
	presents with more easy to comprehend details, such as the total runtime for the various states
	and the time ratio per state of the total query runtime. 
</p>

<p>
	Most notable, the <strong>state_duration_pct</strong> column allows one to quickly analyze the
	states which consumed most of a query's runtime.
</p>

<p>
	To populate this view, one must enable profiling. This is done by:
	<blockquote><pre>mysql&gt; SET PROFILING := 1;
</pre></blockquote>
</p>

<p>
	This code is based on queries presented on
	<a href="http://www.mysqlperformanceblog.com/2012/02/20/how-to-convert-show-profiles-into-a-real-profile/">How to convert MySQL’s SHOW PROFILES into a real profile</a>
	and in the book <i>High Performance MySQL, 3nd Edition</i>, By Baron Schwartz et al., published by O'REILLY
</p>

<h3>STRUCTURE</h3>

<blockquote><pre>
mysql&gt; DESC common_schema.last_query_profiling;
+-------------------------+----------------+------+-----+---------+-------+
| Field                   | Type           | Null | Key | Default | Extra |
+-------------------------+----------------+------+-----+---------+-------+
| QUERY_ID                | int(20)        | NO   |     | 0       |       |
| STATE                   | varchar(30)    | NO   |     |         |       |
| state_calls             | bigint(21)     | NO   |     | 0       |       |
| state_sum_duration      | decimal(31,6)  | YES  |     | NULL    |       |
| state_duration_per_call | decimal(35,10) | YES  |     | NULL    |       |
| state_duration_pct      | decimal(37,2)  | YES  |     | NULL    |       |
| state_seqs              | longblob       | YES  |     | NULL    |       |
+-------------------------+----------------+------+-----+---------+-------+
</pre></blockquote>

<h3>SYNOPSIS</h3>

<p>Columns of this view:
	<ul>
		<li><strong>QUERY_ID</strong>: identifier of a query, as presented on SHOW PROFILES</li>
		<li><strong>STATE</strong>: a state in query execution</li>
		<li><strong>state_calls</strong>: number of calls for this state in this query</li>
		<li><strong>state_sum_duration</strong>: the total time calls to this state consumed in this query</li>
		<li><strong>state_duration_per_call</strong>: the average time calls to this state consumed in this query</li>
		<li><strong>state_duration_pct</strong>: the percentage of time consumed by calls to this state, of the total time consumed by this query</li>
		<li><strong>state_seqs</strong>: sequence numbers of calls to this state</li>
	</ul>
</p>

<h3>EXAMPLES</h3>
<p>Issue a couple queries, view profiling info:

<blockquote><pre>mysql&gt; SET PROFILING := 1;

mysql&gt; SELECT COUNT(*) FROM sakila.nicer_but_slower_film_list INTO @dummy;

mysql&gt; SELECT COUNT(*) FROM world.City INTO @dummy;

mysql&gt; SELECT * FROM query_profiling;
+----------+----------------------+-------------+--------------------+-------------------------+--------------------+------------+
| QUERY_ID | STATE                | state_calls | state_sum_duration | state_duration_per_call | state_duration_pct | state_seqs |
+----------+----------------------+-------------+--------------------+-------------------------+--------------------+------------+
|        1 | checking permissions |           5 |           0.000342 |            0.0000684000 |               0.49 | 5,6,7,8,9  |
|        1 | cleaning up          |           1 |           0.000008 |            0.0000080000 |               0.01 | 31         |
|        1 | closing tables       |           1 |           0.000018 |            0.0000180000 |               0.03 | 29         |
|        1 | Copying to tmp table |           1 |           0.044438 |            0.0444380000 |              63.34 | 15         |
|        1 | Creating tmp table   |           1 |           0.000202 |            0.0002020000 |               0.29 | 13         |
|        1 | end                  |           1 |           0.000005 |            0.0000050000 |               0.01 | 23         |
|        1 | executing            |           2 |           0.000018 |            0.0000090000 |               0.03 | 14,22      |
|        1 | freeing items        |           2 |           0.000227 |            0.0001135000 |               0.32 | 25,27      |
|        1 | init                 |           1 |           0.000012 |            0.0000120000 |               0.02 | 20         |
|        1 | logging slow query   |           1 |           0.000004 |            0.0000040000 |               0.01 | 30         |
|        1 | Opening tables       |           1 |           0.000284 |            0.0002840000 |               0.40 | 2          |
|        1 | optimizing           |           2 |           0.000033 |            0.0000165000 |               0.05 | 10,21      |
|        1 | preparing            |           1 |           0.000025 |            0.0000250000 |               0.04 | 12         |
|        1 | query end            |           1 |           0.000005 |            0.0000050000 |               0.01 | 24         |
|        1 | removing tmp table   |           3 |           0.000149 |            0.0000496667 |               0.21 | 18,26,28   |
|        1 | Sending data         |           2 |           0.017748 |            0.0088740000 |              25.30 | 17,19      |
|        1 | Sorting result       |           1 |           0.006466 |            0.0064660000 |               9.22 | 16         |
|        1 | starting             |           1 |           0.000076 |            0.0000760000 |               0.11 | 1          |
|        1 | statistics           |           1 |           0.000075 |            0.0000750000 |               0.11 | 11         |
|        1 | System lock          |           1 |           0.000010 |            0.0000100000 |               0.01 | 3          |
|        1 | Table lock           |           1 |           0.000017 |            0.0000170000 |               0.02 | 4          |
|        2 | cleaning up          |           1 |           0.000010 |            0.0000100000 |               2.90 | 12         |
|        2 | end                  |           1 |           0.000012 |            0.0000120000 |               3.48 | 8          |
|        2 | executing            |           1 |           0.000019 |            0.0000190000 |               5.51 | 7          |
|        2 | freeing items        |           1 |           0.000038 |            0.0000380000 |              11.01 | 10         |
|        2 | init                 |           1 |           0.000025 |            0.0000250000 |               7.25 | 5          |
|        2 | logging slow query   |           1 |           0.000010 |            0.0000100000 |               2.90 | 11         |
|        2 | Opening tables       |           1 |           0.000031 |            0.0000310000 |               8.99 | 2          |
|        2 | optimizing           |           1 |           0.000016 |            0.0000160000 |               4.64 | 6          |
|        2 | query end            |           1 |           0.000015 |            0.0000150000 |               4.35 | 9          |
|        2 | starting             |           1 |           0.000135 |            0.0001350000 |              39.13 | 1          |
|        2 | System lock          |           1 |           0.000014 |            0.0000140000 |               4.06 | 3          |
|        2 | Table lock           |           1 |           0.000020 |            0.0000200000 |               5.80 | 4          |
+----------+----------------------+-------------+--------------------+-------------------------+--------------------+------------+
</pre></blockquote>
</p>

<p>Similar to the above, simplify results:
<blockquote><pre>mysql&gt; SET PROFILING := 1;

mysql&gt; SELECT COUNT(*) FROM sakila.nicer_but_slower_film_list INTO @dummy;

mysql&gt; SELECT query_id, state, state_duration_pct, state_calls 
          FROM query_profiling 
          ORDER BY query_id ASC, state_duration_pct DESC;
+----------+----------------------+--------------------+-------------+
| query_id | state                | state_duration_pct | state_calls |
+----------+----------------------+--------------------+-------------+
|        1 | Copying to tmp table |              69.63 |           1 |
|        1 | Sending data         |              20.00 |           2 |
|        1 | Sorting result       |               8.92 |           1 |
|        1 | freeing items        |               0.37 |           2 |
|        1 | checking permissions |               0.28 |           5 |
|        1 | Opening tables       |               0.22 |           1 |
|        1 | Creating tmp table   |               0.15 |           1 |
|        1 | removing tmp table   |               0.15 |           3 |
|        1 | starting             |               0.07 |           1 |
|        1 | statistics           |               0.05 |           1 |
|        1 | optimizing           |               0.03 |           2 |
|        1 | closing tables       |               0.02 |           1 |
|        1 | executing            |               0.02 |           2 |
|        1 | preparing            |               0.02 |           1 |
|        1 | cleaning up          |               0.01 |           1 |
|        1 | init                 |               0.01 |           1 |
|        1 | System lock          |               0.01 |           1 |
|        1 | Table lock           |               0.01 |           1 |
|        1 | end                  |               0.00 |           1 |
|        1 | logging slow query   |               0.00 |           1 |
|        1 | query end            |               0.00 |           1 |
|        2 | starting             |              37.39 |           1 |
|        2 | freeing items        |              12.16 |           1 |
|        2 | Opening tables       |               8.81 |           1 |
|        2 | init                 |               7.29 |           1 |
|        2 | executing            |               5.78 |           1 |
|        2 | Table lock           |               5.78 |           1 |
|        2 | optimizing           |               4.86 |           1 |
|        2 | System lock          |               4.26 |           1 |
|        2 | logging slow query   |               3.65 |           1 |
|        2 | cleaning up          |               3.34 |           1 |
|        2 | end                  |               3.34 |           1 |
|        2 | query end            |               3.34 |           1 |
+----------+----------------------+--------------------+-------------+
</pre></blockquote>
As a point of interest, we can see that <i>"Opening tables"</i> is no longer a major impacting state.
</p>

<h3>ENVIRONMENT</h3>
MySQL 5.1 or newer.

<h3>SEE ALSO</h3>
<a href="last_query_profiling.html">last_query_profiling</a>

<h3>AUTHOR</h3>
Shlomi Noach
				<br/>
			</div>
			<div id="sidebarwrapper">
				<div id="search">
					Search online documentation
					<form id="search_form" name="search_form" method="GET" 
						action="http://www.google.com/search" 
						onsubmit="document.forms['search_form']['q'].value = 'site:http://common-schema.googlecode.com/svn/trunk/common_schema/doc/html/ '+document.forms['search_form']['search_term'].value;">
						<input type="text" name="search_term" value=""/>
						<input type="hidden" name="q" value=""/>
						<input type="submit" value="go"/>						
					</form>
				</div>
				<div id="menu">
					<ul>
						<li><a title="Introduction" href="introduction.html">Introduction</a></li>
						<li><a title="Documentation" href="documentation.html">Documentation</a></li>
						<li><a title="Download" href="download.html">Download</a></li>
						<li><a title="Install" href="install.html">Install</a></li>
						<li><a title="Risks" href="risks.html">Risks</a></li>
					</ul>						
					<h3>QUERY SCRIPT</h3>
					<ul>
						<li><a title="QueryScript" href="query_script.html">QueryScript</a></li>
						<li><a title="Execution" href="query_script_execution.html">Execution</a></li>
						<li><a title="Flow control" href="query_script_flow_control.html">Flow control</a></li>
						<li><a title="Statements" href="query_script_statements.html">Statements</a></li>
						<li><a title="Expressions" href="query_script_expressions.html">Expressions</a></li>
						<li><a title="Variables" href="query_script_variables.html">Variables</a></li>
					</ul>						
					<h3>DEBUG</h3>
					<ul>
						<li><a title="rdebug" href="rdebug.html">rdebug</a></li>
						<li><a title="rdebug API" href="rdebug_api.html">rdebug API</a></li>
						<li><a title="rdebug workflow" href="rdebug_workflow.html">Workflow</a></li>
					</ul>						
					<h3>ROUTINES</h3>
					<ul>
						<li><a title="Execution &amp; flow control" href="execution_routines.html">Execution & flow control</a></li>
						<li><a title="General" href="general_routines.html">General</a></li>
						<li><a title="Process" href="process_routines.html">Process</a></li>
						<li><a title="Query analysis" href="query_analysis_routines.html">Query analysis</a></li>
						<li><a title="Schema analysis" href="schema_analysis_routines.html">Schema analysis</a></li>
						<li><a title="Security" href="security_routines.html">Security</a></li>
						<li><a title="Text" href="text_routines.html">Text</a></li>
						<li><a title="Time &amp; date" href="temporal_routines.html">Time & date</a></li>
						<li><a title="Charting" href="charting_routines.html">Charting</a></li>
					</ul>
					<h3>VIEWS</h3>
					<ul>
						<li><a title="Schema analysis" href="schema_analysis_views.html">Schema analysis</a></li>
						<li><a title="Data dimension" href="data_dimension_views.html">Data dimension</a></li>
						<li><a title="Process" href="process_views.html">Process</a></li>
						<li><a title="Security" href="security_views.html">Security</a></li>
						<li><a title="Monitoring" href="monitoring_views.html">Monitoring</a></li>
						<li><a title="InnoDB Plugin" href="innodb_plugin_views.html">InnoDB Plugin</a></li>
						<li><a title="Percona server" href="percona_server_views.html">Percona Server</a></li>
						<li><a title="TokuDB" href="tokudb_views.html">TokuDB</a></li>
					</ul>						
					<h3>DATA</h3>
					<ul>
						<li><a title="tables" href="tables.html">Tables</a></li>
						<li><a title="variables" href="variables.html">Variables</a></li>
					</ul>						
					<h3>META</h3>
					<ul>
						<li><a title="Help" href="help.html">help</a></li>
						<li><a title="Metadata" href="metadata.html">metadata</a></li>
						<li><a title="status" href="status.html">status</a></li>
					</ul>						
				</div>
			</div>	
			<div class="clear">&nbsp;</div>
			
			<div id="footnote" align="center">
				<a href="">common_schema</a> documentation
			</div>
		</div>
	</div>
</body>
</html>
